Skip to content

Fixes issue #9347 - jump to live on seek to 0#753

Merged
copybara-service[bot] merged 2 commits intoandroidx:mainfrom
stevemayhew:p-fix-issue-9347
Dec 14, 2023
Merged

Fixes issue #9347 - jump to live on seek to 0#753
copybara-service[bot] merged 2 commits intoandroidx:mainfrom
stevemayhew:p-fix-issue-9347

Conversation

@stevemayhew
Copy link
Contributor

Using 0 as the unset prepare position is the root cause of a number of issues, as outliine in the ExoPlayer issue google/ExoPlayer#7975

The premise of this fix is that once the prepare override is used (the initial call to selectTracks()) it is never needed again, so simply invalidate it after use.

@stevemayhew
Copy link
Contributor Author

stevemayhew commented Oct 20, 2023

Overview

@icbaker here's the pull request migrated from ExoPlayer codebase.

To see this bug, checkout my branch x-logging-demo-issue-9347-seek-0-jumps-live, you can then cherry-pick this commit to see it fixes the bug.

@marcbaechinger this is the same seekTo(0) bug we still have, it is just a harder use case to work around. I'm looking at a longer fix that propagates a proper "use default" when using seekToDefaultPosition() for preparePositionUs that eliminates 0 as a sentinel value (see comment google/ExoPlayer#7975 (comment)), but that change will be substantially more complex than this one.

We have several use cases that trigger this bug, so we are using this fix in our branch now.

Here's the logging from that branch along with my analysis and description of the fix and alternatives

Analysis and logging

Initial MaskingMediaSource create and prepare

10-19 14:54:19.587 23352 23492 D MaskingMediaSource: createPeriod() id: androidx.media3.exoplayer.source.MediaSource$MediaPeriodId@8a6b965d startPositionUs: 0 isPrepared: false unpreparedMaskingMediaPeriod: null
10-19 14:54:19.590 23352 23492 D MaskingMediaPeriod: create MaskingMediaPeriod [ preparePositionOverrideUs: -9223372036854775807, preparePositionUs: 0 maskedPeriod: null]
10-19 14:54:19.596 23352 23352 D EventLogger: state [eventTime=0.20, mediaPos=0.00, window=0, BUFFERING]
10-19 14:54:19.623 23352 23352 D PlayerActivity: onPlaybackStateChanged() - 2
10-19 14:54:19.634 23352 23492 D MaskingMediaPeriod: prepare() - positionUs: 0 this.preparePositionUs:  0, with override: 0
10-19 14:54:20.224 23352 23352 D EventLogger: surfaceSize [eventTime=0.83, mediaPos=0.00, window=0, 1920, 1080]
10-19 14:54:20.521 23352 23352 D EventLogger: loading [eventTime=1.12, mediaPos=0.00, window=0, period=0, true]

First HLS playlist update sets the override based on the window computed start position

10-19 14:54:22.327 23352 23492 D MaskingMediaSource: onChildSourceInfoRefreshed() not prepared - 
       timeline: androidx.media3.exoplayer.source.MaskingMediaSource$MaskingTimeline@b7e88a50 
       unpreparedMaskingMediaPeriod: MaskingMediaPeriod [ preparePositionOverrideUs: -9223372036854775807, preparePositionUs: 0 maskedPeriod: null] 
       windowStartPositionUs: 1777776000 
       oldWindowDefaultPositionUs: 0
10-19 14:54:22.329 23352 23492 D MaskingMediaPeriod: createPeriod(androidx.media3.exoplayer.source.MediaSource$MediaPeriodId@5446db1) - preparePositionUs: 0 with override: 1777776000
10-19 14:54:27.464 23352 23492 D MaskingMediaPeriod: onPrepared() - mediaPeriod: androidx.media3.exoplayer.hls.HlsMediaPeriod@cfc5940 this: MaskingMediaPeriod [ preparePositionOverrideUs: 1777776000, preparePositionUs: 0 maskedPeriod: androidx.media3.exoplayer.hls.HlsMediaPeriod@cfc5940]
10-19 14:54:27.492 23352 23352 D EventLogger: timeline [eventTime=8.09, mediaPos=1777.78, window=0, period=0, periodCount=1, windowCount=1, reason=SOURCE_UPDATE
10-19 14:54:27.493 23352 23352 D EventLogger:   period [?]
10-19 14:54:27.496 23352 23352 D EventLogger:   window [1801.80, seekable=true, dynamic=true]

Note at this point prepare is completed, the position is already reported correctly in the EventLogger event, so Player.getCurrentPosition() is returning the position already.... And this is the position that is passed into selectTracks(). The "default" preparePositionUs Is still 0, so selectTracks() returns the already set position, the override position is ignored. Code for reference:

  @Override
  public long selectTracks(
      @NullableType ExoTrackSelection[] selections,
      boolean[] mayRetainStreamFlags,
      @NullableType SampleStream[] streams,
      boolean[] streamResetFlags,
      long positionUs) {
    Log.d(TAG, "selectTracks() - positionUs: " + positionUs
        + " preparePositionUs: " + preparePositionUs
        + " preparePositionOverrideUs: " + preparePositionOverrideUs);
    if (preparePositionOverrideUs != C.TIME_UNSET && positionUs == preparePositionUs) {
      Log.d(TAG, "selectTracks() - reset positionOverrideUs");
      positionUs = preparePositionOverrideUs;
      preparePositionOverrideUs = C.TIME_UNSET;
    }
    long resolvedPositionUs = castNonNull(mediaPeriod)
        .selectTracks(selections, mayRetainStreamFlags, streams, streamResetFlags, positionUs);
    Log.d(TAG, "selectTracks() - return positionUs: " + positionUs);
10-19 14:54:27.496 23352 23352 D EventLogger: ]
10-19 14:54:28.489 23352 23492 D MaskingMediaPeriod: selectTracks() - positionUs: 1777776000 preparePositionUs: 0 preparePositionOverrideUs: 1777776000
10-19 14:54:28.493 23352 23492 D MaskingMediaPeriod: selectTracks() - return positionUs: 1777776000

Now the code to trigger the bug runs...

0-19 14:54:29.570 23352 23352 D EventLogger: renderedFirstFrame [eventTime=10.17, mediaPos=1777.78, window=0, period=0, Surface(name=null)/@0xc58671e]
10-19 14:54:30.323 23352 23352 D EventLogger: state [eventTime=10.93, mediaPos=1777.81, window=0, period=0, READY]
10-19 14:54:30.324 23352 23352 D PlayerActivity: onPlaybackStateChanged() - 3
10-19 14:54:30.336 23352 23352 D PlayerActivity: seekTo - 1777815
10-19 14:54:30.428 23352 23492 D MaskingMediaPeriod: selectTracks() - positionUs: 1777865176 preparePositionUs: 0 preparePositionOverrideUs: 1777776000
10-19 14:54:30.435 23352 23492 D MaskingMediaPeriod: selectTracks() - return positionUs: 1777865176
10-19 14:54:30.862 23352 23352 D PlayerActivity: seekTo - 1177815
10-19 14:54:31.376 23352 23352 D PlayerActivity: seekTo - 577815
10-19 14:54:31.898 23352 23352 D PlayerActivity: seekTo final to 0
10-19 14:54:31.909 23352 23352 D PlayerActivity: run track selection
10-19 14:54:31.973 23352 23352 D EventLogger: isPlaying [eventTime=12.58, mediaPos=0.00, window=0, period=0, true]
10-19 14:54:31.984 23352 23352 D EventLogger: positionDiscontinuity [eventTime=12.59, mediaPos=0.00, window=0, period=0, reason=SEEK, PositionInfo:old [mediaItem=0, period=0, pos=1777815], PositionInfo:new [mediaItem=0, period=0, pos=1777815]]
10-19 14:54:32.028 23352 23352 D EventLogger: state [eventTime=12.63, mediaPos=0.00, window=0, period=0, BUFFERING]
10-19 14:54:32.029 23352 23352 D PlayerActivity: onPlaybackStateChanged() - 2
10-19 14:54:32.075 23352 23352 D EventLogger: isPlaying [eventTime=12.68, mediaPos=0.00, window=0, period=0, false]

Seek to 0 is logged, all good.

10-19 14:54:32.083 23352 23352 D EventLogger: positionDiscontinuity [eventTime=12.69, mediaPos=0.00, window=0, period=0, reason=SEEK, PositionInfo:old [mediaItem=0, period=0, pos=1777815], PositionInfo:new [mediaItem=0, period=0, pos=1177815]]
10-19 14:54:32.121 23352 23352 D EventLogger: positionDiscontinuity [eventTime=12.73, mediaPos=0.00, window=0, period=0, reason=SEEK, PositionInfo:old [mediaItem=0, period=0, pos=1177815], PositionInfo:new [mediaItem=0, period=0, pos=577815]]

And here the bug occurs. MaskingMediaPeriod.selectTracks() pull the stale preparePositionOverrideUs out and returns it. Chaging the valid explict posiiton of 0 to the override position.

I think there are a couple of fixes to this, easiest first:

  1. Once the preparePositionOverrideUs is used once the prepare() is complete, so it can be neutered to C.TIME_UNSET.
  2. Preserve the C.TIME_UNSET from Player.seekToDefault() when it passes through `Timeline.getPeriodPositionUs(...)

The longer fix (#2) is needed for the issue @marc discussed here: google/ExoPlayer#7975 (comment)

For now, I've taken the easiest, which fixes issue google/ExoPlayer#9347

10-19 14:54:32.146 23352 23492 D MaskingMediaPeriod: selectTracks() - positionUs: 0 preparePositionUs: 0 preparePositionOverrideUs: 1777776000
10-19 14:54:32.146 23352 23492 D MaskingMediaPeriod: selectTracks() - reset positionOverrideUs
10-19 14:54:32.151 23352 23492 D MaskingMediaPeriod: selectTracks() - return positionUs: 1777776000

@icbaker
Copy link
Collaborator

icbaker commented Oct 20, 2023

Can you please update this to be proposed against the main branch?

@stevemayhew stevemayhew changed the base branch from release to main October 21, 2023 09:53
@stevemayhew
Copy link
Contributor Author

Can you please update this to be proposed against the main branch?

Sure, I'll fix the messed up merge GitHub did then rebase and force push it

@stevemayhew
Copy link
Contributor Author

@icbaker I've rebased this branch and the branch with the test logging (https://github.com/stevemayhew/media/tree/x-logging-demo-issue-9347-seek-0-jumps-live) to main to make it easy to merge.

The only use-case I've found the override code, in the selectTracks() path, is needed is when a previous live timeline errors out and in the error recovery calls Player.setDefaultStart(). You can see an example of that in the ERROR_CODE_IO_NETWORK_CONNECTION_FAILED recovery in the x-logging-demo-issue-9347-seek-0-jumps-live PlayerActivity code.

Let me know if you'd like a live HLS test URL for this.

@icbaker icbaker requested review from tonihei and removed request for marcbaechinger October 23, 2023 10:48
@icbaker icbaker assigned tonihei and unassigned marcbaechinger Oct 23, 2023
@tonihei
Copy link
Collaborator

tonihei commented Oct 31, 2023

The only use-case I've found the override code, in the selectTracks() path, is needed is when a previous live timeline errors out and in the error recovery calls Player.setDefaultStart(). You can see an example of that in the ERROR_CODE_IO_NETWORK_CONNECTION_FAILED recovery in the x-logging-demo-issue-9347-seek-0-jumps-live PlayerActivity code.

Thanks for all the details and explanations! If I understand everything correctly, your change is mostly working, except that it causes a regression for this particular case? I was trying to craft a unit test in ExoPlayerTest to capture this as well, but couldn't find one so far that works before this change, but fails after.

@stevemayhew
Copy link
Contributor Author

Thanks for all the details and explanations! If I understand everything correctly, your change is mostly working, except that it causes a regression for this particular case?

The change in this pull request is working perfectly. The problem I'm referencing to (RE: ERROR_CODE_IO_NETWORK_CONNECTION_FAILED recovery)) happened because of a previous pull request I made for this issue that remove the override code in the selectTracks() completely. The code in MaskingMediaSource.onChildSourceInfoRefreshed() handles setting the position to the live start in every other case but this one. In this case the preparePositionOverrideUs in selectTracks() is the only path that sets the position back to the default start.

I was trying to craft a unit test in ExoPlayerTest to capture this as well, but couldn't find one so far that works before this change, but fails after.

Not surprised, when I completely removed the preparePositionOverrideUs code in MaskingMediaPeriod all the unit test cases still pass. The logic in MaskingMediaPeriod that determines start position handles almost every case except the connection failed error.

To reproduce the connection failed error (recovery logic is in the branch, x-logging-demo-issue-9347-seek-0-jumps-live) I did this:

  1. Play a live stream.
  2. Disconnect the lan cable and wait till the ERROR_CODE_IO_NETWORK_CONNECTION_FAILED becomes fatal.
  3. Reconnect the lan cable (good to reconnect adb here and look at the logcat output during recovery)
  4. Select "Retry" in the recovery dialog.

Without the code in selectTracks() to apply the override the new default live position is ignored, that is we stay at near the live edge when the fatal error occurred. Of course this goes badly for buffering.

@stevemayhew
Copy link
Contributor Author

Sorry to mix up multiple issues in this discussion.. But I think we can solve the LAN disconnect exhausted buffer in the MaskingMediaSource.onChildSourceInfoRefreshed() completely, in which case the code in selectTracks() would not be needed (at least for the use cases I know of).

@tonihei
Copy link
Collaborator

tonihei commented Nov 2, 2023

Not surprised, when I completely removed the preparePositionOverrideUs code in MaskingMediaPeriod all the unit test cases still pass.

Huh... you're right, but that feels unexpected! This either means we are missing a crucial test case or the code is indeed unneeded by now.

The logic in MaskingMediaPeriod that determines start position handles almost every case except the connection failed error.

Was this meant to be MaskingMediaSource? Otherwise I'm confused what you are referring to exactly.

The change in this pull request is working perfectly. The problem I'm referencing to (RE: ERROR_CODE_IO_NETWORK_CONNECTION_FAILED recovery)) happened because of a previous pull request I made for this issue that remove the override code in the selectTracks() completely. The code in MaskingMediaSource.onChildSourceInfoRefreshed() handles setting the position to the live start in every other case but this one. In this case the preparePositionOverrideUs in selectTracks() is the only path that sets the position back to the default start.

So just to summarize my understanding:

  • Removing the preparePositionOverrideUs in MaskingMediaPeriod entirely is wrong because it's needed for this one connection-failed recovery you describe here.
  • Resetting the value to UNSET (=this PR) fixes ExoPlayer#9347, but does not effect the connection-failed recovery because this path still gets the initial override.

=> conclusion is that this PR is safe and at least fixed ExoPlayer#9347
=> alternative approach: remove preparePositionOverrideUs in MaskingMediaPeriod entirely and somehow handle the connection-failed recovery in MaskingMediaSource.

Does that correspond to what you are saying?

@stevemayhew
Copy link
Contributor Author

Was this meant to be MaskingMediaSource? Otherwise I'm confused what you are referring to exactly.

The change in this pull request is working perfectly. The problem I'm referencing to (RE: ERROR_CODE_IO_NETWORK_CONNECTION_FAILED recovery)) happened because of a previous pull request I made for this issue that remove the override code in the selectTracks() completely. The code in MaskingMediaSource.onChildSourceInfoRefreshed() handles setting the position to the live start in every other case but this one. In this case the preparePositionOverrideUs in selectTracks() is the only path that sets the position back to the default start.

Correct, if you create this error and look at the logging...

Here's the last retry that becomes a fatal error, note the position (end of the timeline basically):

11-03 16:14:46.345 23423 23423 D PlayerActivity: onPlayerError() - ERROR_CODE_IO_NETWORK_CONNECTION_FAILED
11-03 16:14:46.517  3724  3924 E WindowManager: App trying to use insecure INPUT_FEATURE_NO_INPUT_CHANNEL flag. Ignoring
11-03 16:14:46.523 23423 23423 D EventLogger: loading [eventTime=42.85, mediaPos=1801.66, window=0, period=0, false]
11-03 16:14:46.524 23423 23423 D EventLogger: state [eventTime=42.86, mediaPos=1801.66, window=0, period=0, IDLE]
11-03 16:14:46.524 23423 23423 D PlayerActivity: onPlaybackStateChanged() - 1
11-03 16:14:46.529 23423 23423 D EventLogger: isPlaying [eventTime=42.86, mediaPos=1801.66, window=0, period=0, false]

After the LAN cable is reconnected, then you click "retry" and the recovery code runs (basically just does a seekToDefaultPosition() then a prepare()) you can see the old position (1801661, near the end of the timeline) is set as the startPositionUs. The sequence is:

Seek to default:

11-03 16:15:15.617 23423 23423 D EventLogger: positionDiscontinuity [eventTime=71.95, mediaPos=1771.77, window=0, period=0, reason=SEEK, PositionInfo:old [mediaItem=0, period=0, pos=1801661], PositionInfo:new [mediaItem=0, period=0, pos=1771770]]
11-03 16:15:15.622 23423 23423 D EventLogger: positionDiscontinuity [eventTime=71.96, mediaPos=1771.77, window=0, period=0, reason=SEEK, PositionInfo:old [mediaItem=0, period=0, pos=1771770], PositionInfo:new [mediaItem=0, period=0, pos=1771770]]

The MaskingMediaSource is created with a very wrong startPositionIUs

11-03 16:15:15.625 23423 23587 D MaskingMediaSource: createPeriod() id: androidx.media3.exoplayer.source.MediaSource$MediaPeriodId@c2b8f42a startPositionUs: 1789770000 isPrepared: false unpreparedMaskingMediaPeriod: null
11-03 16:15:15.625 23423 23587 D MaskingMediaPeriod: create MaskingMediaPeriod [ preparePositionOverrideUs: -9223372036854775807, preparePositionUs: 1789770000 maskedPeriod: null]
11-03 16:15:15.625 23423 23587 D MaskingMediaPeriod: create MaskingMediaPeriod [ preparePositionOverrideUs: -9223372036854775807, preparePositionUs: 1789770000 maskedPeriod: null]
11-03 16:15:15.626 23423 23423 D EventLogger: state [eventTime=71.96, mediaPos=1771.77, window=0, period=0, BUFFERING]
11-03 16:15:15.626 23423 23423 D PlayerActivity: onPlaybackStateChanged() - 2
11-03 16:15:15.627 23423 23587 D MaskingMediaPeriod: prepare() - positionUs: 1789770000 this.preparePositionUs:  1789770000, with override: 1789770000

Then the first playlist load establishes the window default start, at this point we have everything needed to establish the correct starting position, except the initial preparePositionUs is incorrect (it should be the default as requested)

11-03 16:15:15.954 23423 23587 D MaskingMediaSource: onChildSourceInfoRefreshed() not prepared - timeline: androidx.media3.exoplayer.source.MaskingMediaSource$MaskingTimeline@fe6df274 unpreparedMaskingMediaPeriod: MaskingMediaPeriod [ preparePositionOverrideUs: -9223372036854775807, preparePositionUs: 1789770000 maskedPeriod: null] windowStartPositionUs: 1777776000 oldWindowDefaultPositionUs: 1771770000
11-03 16:15:15.955 23423 23587 D MaskingMediaPeriod: createPeriod(androidx.media3.exoplayer.source.MediaSource$MediaPeriodId@3f8a65f1) - preparePositionUs: 1789770000 with override: 1777776000
11-03 16:15:15.971 23423 23587 D MaskingMediaPeriod: onPrepared() - mediaPeriod: androidx.media3.exoplayer.hls.HlsMediaPeriod@3800d19 this: MaskingMediaPeriod [ preparePositionOverrideUs: 1777776000, preparePositionUs: 1789770000 maskedPeriod: androidx.media3.exoplayer.hls.HlsMediaPeriod@3800d19]

Things would go badly, if not for the code in selectTracks() that kicks in to reset the position based on the override:

11-03 16:15:15.982 23423 23587 D MaskingMediaPeriod: selectTracks() - positionUs: 1777776000 preparePositionUs: 1789770000 preparePositionOverrideUs: 1777776000
11-03 16:15:15.983 23423 23587 D MaskingMediaPeriod: selectTracks() - return positionUs: 1777776000

So, if we remove that code (which test cases indicates we should), then we need to fix the initial prepare position so the
code in onChildSourceInfoRefreshed() does the correct thing earlier (also gets us a jump on loading the correct segments).

So just to summarize my understanding:

  • Removing the preparePositionOverrideUs in MaskingMediaPeriod entirely is wrong because it's needed for this one connection-failed recovery you describe here.
  • Resetting the value to UNSET (=this PR) fixes ExoPlayer#9347, but does not effect the connection-failed recovery because this path still gets the initial override.

=> conclusion is that this PR is safe and at least fixed ExoPlayer#9347 => alternative approach: remove preparePositionOverrideUs in MaskingMediaPeriod entirely and somehow handle the connection-failed recovery in MaskingMediaSource.

Does that correspond to what you are saying?

All correct, I think fixing the code to be able to remove the selectTracks() override logic requires the same area of work needed to fix the initial seek to 0 bug. Happy to work on this, but not now ;-)

@tonihei
Copy link
Collaborator

tonihei commented Nov 7, 2023

Thanks, so sounds like we can merge this PR. Do you want to add a test case for the ExoPlayer#9347 case? I think I saw one somewhere already but couldn't find it right now.

@stevemayhew
Copy link
Contributor Author

stevemayhew commented Nov 8, 2023 via email

@tonihei
Copy link
Collaborator

tonihei commented Dec 11, 2023

Just checking if you found the chance to add (or rather find) the test case?

@stevemayhew
Copy link
Contributor Author

Yes my old attempt at unit test didn't really work... The logic includes code from MaskingMediaSource, MaskingMediaPeriod, etc so looks like best way is to add to the more functional test in ExoPlayerTest. If you are good that approach I'll continue. At least one test hits the affected code (seekAndReprepareAfterPlaybackError_keepsSeekPositionAndTimeline). but nothing hits the required conditions:

  1. override is set by the initial source update (don't really need HLS data source to do this I think)
  2. selectTracks() called with position 0 and prepare position is 0 already

With these two the second selectTracks() will jump to the wrong position. Lots of steps to code in an ExoPlayerTest so it will take me a bit, the framework is pretty good though, should be able to code the sequence from the demo player with that.

@tonihei
Copy link
Collaborator

tonihei commented Dec 12, 2023

I was able to create a test case with the problematic sequence in #9347 (initial start with non-zero default + later seekTo(0) + track selection). Will merge this change and add the test myself, thanks!

@stevemayhew
Copy link
Contributor Author

Thanks @tonihei, getting the hang of the ExoPlayerTest pretty cool what you can do. Also nice you can push to our pull request branches, keeps the merges cleaner.

Let me known anything you need from me to close out the bug and complete the pull request, from our side this code fixes the issue.

stevemayhew and others added 2 commits December 13, 2023 14:48
Using 0 as the unset prepare position is the root cause of a number of issues,
as outliine in the ExoPlayer issue google/ExoPlayer#7975

The premise of this fix is that once the prepare override is used (the initial call
to `selectTracks()`) it is never needed again, so simply invalidate it after use.
@copybara-service copybara-service bot merged commit ab296ef into androidx:main Dec 14, 2023
microkatz pushed a commit that referenced this pull request Jan 11, 2024
PiperOrigin-RevId: 590862514
(cherry picked from commit ab296ef)
@fourofspades
Copy link

fourofspades commented Jan 14, 2024

I think my app may be affected by an issue in this area. I use a Forwarding player, and override the Play method and add a super.seekTo(0) as I had an issue where network drop outs would cause odd behaviour with the buffering, where it would continue to play a live steam when the network returned, and then, presumably, when the buffer was empty, jump to the latest part of the stream. For a network streaming radio, this didn't make any sense. It made more sense to jump to the live stream when the network returned. super.seekTo(0) for the most part, mostly fixes this.

That said, there is still an edge case, where if the network is lost for an extended period, the radio stream will never resume, sit there forever doing something, not sure what. Playing/Pausing won't fix it. The only fix is to change "track", and return back,

I guess my question is:

Is there a fix here (or somewhere else) that might fix this (I'm currently seeing this in media3 1.2.0 ), Otherwise, is there something better I should be doing in my ForwardingPlayer to overcome this?

Thanks.

@stevemayhew
Copy link
Contributor Author

stevemayhew commented Jan 14, 2024 via email

@androidx androidx locked and limited conversation to collaborators Feb 13, 2024
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

5 participants